14. Logging

Logging overview

In the code for the simple_mover , arm_mover , and look_away nodes, you may have noticed logging statements such as: 

rospy.logwarn('j1 is out of bounds, valid range (%s,%s), clamping to: %s', 
               min_j1, max_j1, clamped_j1)

and 

rospy.loginfo('GoToPositionRequest Received - j1:%s, j2:%s', 
               req.joint_1, req.joint_2)

Logging statements allow ROS nodes to send messages to a log file or the console. This allows errors and warnings to be surfaced to the user, or log data to be used later for debugging.

By default all logging messages for a node are written to the node's log file which can be found in ~/.ros/log or ROS_ROOT/log . If roscore is running, you can use roscd to find log file directory by opening a new terminal window and typing: 

roscd log

In this directory, you should see directories from runs of your ROS code, along with a latest directory with log files from the most recent run.

Below, we'll show some of the options available for logging different types of messages, filtering messages, and changing how messages are surfaced to a user.

Logging levels and outputs

Rospy has several message levels and provides a variety of options for how to display or store these messages: 

rospy.logdebug(...)
rospy.loginfo(...)
rospy.logwarn(...)
rospy.logerr(...)
rospy.logfatal(...)

All levels of logging messages are recorded in ROS log files, but some message levels may also be sent to Python stdout , Python stderr , or the ROS topic /rosout .

The loginfo messages are written to Python's stdout , while logwarn , logerr , and logfatal are written to Python's stderr by default. Additionally, loginfo , logwarn , logerr , and logfatal are written to /rosout .

The following table summarizes the default locations log messages are written to (source here ):

Debug Info Warn Error Fatal
stdout X
stderr X X X
log file X X X X X
/rosout X X X X

Filtering and saving log messages from /rosout

Note that for messages written to /rosout , you can see the messages in real time as your program is running by echoing: 

rostopic echo /rosout

Although it can be helpful to view messages this way, because of the volume of messages written to that topic, it can sometimes be helpful to filter messages by piping them to grep . These grepped messages can also be saved to a file for debugging: 

rostopic echo /rosout | grep insert_search_expression_here
rostopic echo /rosout | grep insert_search_expression_here > path_to_output/output.txt

Modifying message level sent to /rosout

Although logdebug messages are not written to /rosout by default, it is possible to modify the level of logging messages written to /rosout to display them there, or change the level of logging messages written to /rosout to be more restrictive. To do this you must set the log_level attribute within the rospy.init_node code. For example, if you'd like to allow lodebug messages to be written to /rosout , that can be done as follows: 

rospy.init_node('my_node', log_level=rospy.DEBUG)

Other possible rospy options for log_level are INFO , WARN , ERROR , and FATAL .

Modifying display of messages sent to stdout and stderr

It is also possible to change how messages to stdout and stderr are displayed or logged. Within a package's .launch file, the output attribute for a node tag can be set to "screen" or "log" . The following table summarizes how the different output options change the display of the node's stdout and stderr messages:

stdout stderr
"screen" screen screen
"log" log screen and log

For example, setting output="screen" for the look_away node in robot_spawn.launch will display both stdout and stderr messages in the screen: 

  <!-- The look away node -->
  <node name="look_away" type="look_away" pkg="simple_arm" output="screen"/>

If the output attribute is left empty, the default is "log" .

As you continue on with the project, the ROS systems that you write will become increasingly complex. Being able to use logging effectively may prove extremely useful for debugging!

Next Concept